fix(index): make a crashed worker's log survive and name the run - #1644
Merged
Conversation
Six reports describe the same dead end: the indexing worker dies, the supervisor points at `logs/.worker-<pid>.log`, and the file is 0 bytes. Nothing was ever flushed, so not one of #1070, #1130, #1132, #1133, #1145 or #1450 is reproducible or attributable -- the hint says "crashed on a file" and the file is never named. Root cause is buffering, not the crash. The worker's stderr is redirected to that log file by the supervisor, and every diagnostic goes through `fprintf(stderr, ...)` with no flush. The C standard only promises stderr is "not fully buffered"; the Windows CRT gives a redirected stderr FULL buffering, which is why five of the six reports are Windows. A worker that aborts, is SIGKILLed by the OOM killer, or is terminated after a hang takes its whole buffer with it. - cbm_log_set_crash_durable(): setvbuf(_IONBF) plus a per-line flush in emit_line. Both, deliberately -- setvbuf covers every writer to the stream including the plain fprintf startup errors that explain a worker which never got as far as logging, and the flush covers the case where setvbuf is refused because the stream was already written to. Enabled for the worker role only, claimed in main() before the process writes anything. - cbm_index_worker_log_begin(): a startup header written and flushed as the worker's first act -- version, build fingerprint, pid, repo path, and the worker's own arguments. A control record rather than an info line, so CBM_LOG_LEVEL cannot restore the 0-byte log. - Under a crash-durable log the parallel extract pass logs every file it starts, not just the first two rounds of workers, so the log ends with the files that were in flight when the worker died. One line per file, never per node; unchanged for every non-worker caller. This fixes no crash. It converts six unreproducible reports into reports we can act on, and every future one arrives with the run identified. Test: a worker started with a fully buffered stderr -- the state the Windows CRT hands it, forced on POSIX so the contract binds on all three legs -- writes diagnostics and is then SIGKILLed. The retained log must be non-empty, carry the header with the version, pid, repo path and args, and still hold the line written after it. Reverting the production change leaves that log at 0 bytes. The probe kills rather than aborts because Darwin's abort() runs the stdio cleanup handler and flushes the very buffer the repro depends on stranding: under abort the reverted build still produced a populated log and the test was quietly toothless. SIGKILL runs no cleanup, and is literally #1070's death (signal=9). Refs #1070 Refs #1130 Refs #1132 Refs #1133 Refs #1145 Refs #1450 Signed-off-by: Martin Vogel <martin.vogel.tech@gmail.com>
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
The problem
Six open reports end at the same dead end. The supervisor contains a worker
failure, prints the log path, and the file is empty:
exit_nonzero, 0 KB loghang+ quarantine, "Worker logs are completely empty"MAX_PATH: "the one diagnostic that would explain the failure is silenced by the failure itself"signal=9, empty logSix reports, zero diagnoses. Not one is reproducible or attributable, and the
hint we print — "Indexing worker crashed on a file" — never names the file.
Root cause: buffering, not the crash
The supervisor redirects the worker's stdout+stderr into the log file
(
options.log_file,subprocess.c), and every diagnostic reaches it throughfprintf(stderr, …)inlog.cwith no flush anywhere.The C standard only promises stderr is "not fully buffered". The Windows CRT
gives a redirected stderr full buffering — which is why five of the six
reports are Windows. A worker that aborts, is SIGKILLed by the OOM killer, or is
terminated after a hang dies with its whole diagnostic still in a userspace
buffer. The file on disk is 0 bytes because nothing was ever written to it.
What this changes
cbm_log_set_crash_durable()—setvbuf(_IONBF)plus a per-line flush inemit_line. Both, deliberately:setvbufcovers every writer to the stream,including the plain
fprintf(stderr, "CBM index worker could not start: …")paths that explain a worker which never got as far as logging; the per-line flush
covers the case where
setvbufis refused because the stream was already writtento (it only binds before a stream's first operation). Enabled for the worker role
only, claimed in
main()before the process writes anything.cbm_index_worker_log_begin()— a startup header written and flushed as theworker's first act: version, build fingerprint, pid, repo path, and the worker's
own arguments. It is a control record, not an info line, so a user running with
CBM_LOG_LEVEL=warncannot end up back at a 0-byte log.Per-file breadcrumb — under a crash-durable log the parallel extract pass logs
every file it starts, not just the first two rounds of workers, so the log ends
with the files that were in flight when the worker died. One line per file, never
per node. Behaviour is unchanged for every non-worker caller.
What a reporter now attaches instead of an empty file (real capture, worker
SIGKILLed mid-run):This fixes no crash. It converts six unreproducible reports into reports we
can act on, and every future one arrives with the run identified. That is the
whole claim — none of these six issues is closed by this PR.
Test
index_supervisor_killed_worker_log_is_never_empty_and_names_the_run(
tests/test_index_supervisor.c, suiteindex_supervisor).A real worker child starts with a fully buffered stderr — the state the
Windows CRT hands a redirected stderr, forced on POSIX by the harness so the
contract binds on all three legs instead of being a Windows-only claim nobody can
run locally. It writes diagnostics and is then SIGKILLed. The supervisor keeps the
log of a failed worker, so what is on disk afterwards is exactly what a user would
attach to an issue. Asserted: non-empty, carries the header with version / pid /
repo path (containing a space, as Windows reporters have) / args, and still holds
the line written after the header.
The probe kills rather than aborts, and that mattered: Darwin's
abort()runsthe stdio cleanup handler and flushes the very buffer the repro depends on
stranding. The first version of this test used
abort(), and the reverted buildstill produced a populated log — the repro was quietly toothless.
SIGKILLcannotbe caught, blocked or handled, so no cleanup of any kind runs; it is also literally
#1070's death (
signal=9) and how #1130's hung worker is terminated.Revert-check — production change reverted (
setvbuf+ per-line flush + headeremission neutralised, test untouched), the log comes back at 0 bytes and the test
fails on the first content assertion. The harness dumps the log at the failure
site and it prints nothing at all:
With the change in place,
./build/c/test-runner index_supervisoris 7/7 greenon macOS arm64 (ASan/UBSan build).